View Issue Details

IDProjectCategoryView StatusLast Update
0001599K18X001.00 SKB SWANSWpublic2023-01-11 10:00
Reporter(ALTech) Sangmin Choi Assigned To(SW) Jim Chen Due Date2023-01-11 18:00
PrioritynormalSeveritys4-minorReproducibilityN/A
Status closedResolutionfixed 
Summary0001599: Please apply this patch from BPM-13992.
DescriptionPlease apply this patch from BPM-13992.

syna-release/ampsdk
TagsNo tags attached.
Attach Tags

Users monitoring this issue

User List There are no users monitoring this issue.

Activities

(ALTech) Sangmin Choi

2023-01-10 14:14

developer  

CSMSAAI-109-91998-458f0fb.diff (26,205 bytes)   
From 458f0fbc2da1fb1ca031911a975ce34d1f86695b Mon Sep 17 00:00:00 2001
From: ztong <Zhe.Tong@synaptics.com>
Date: Fri, 10 Jan 2020 18:37:46 +0800
Subject: [PATCH] AMP: CLK: regulate CHECK_ log for different policy

Change-Id: I04706cfe56ca0c5e2b2357105836350611f5ff97
Reviewed-on: https://sc-debu-git.synaptics.com/gerrit/91998
Reviewed-by: Jenkins
Reviewed-by: Zhe Tong <Zhe.Tong@synaptics.com>
Reviewed-by: Yuanfeng Chu <Yuanfeng.Chu@synaptics.com>
Reviewed-by: Xiaomei Shang <Xiaomei.Shang@synaptics.com>
Reviewed-by: Yanyan Peng <Yanyan.Peng@synaptics.com>
---

diff --git a/amp/src/ddl/comp_clk/source/clk_avsync.c b/amp/src/ddl/comp_clk/source/clk_avsync.c
index 3de6ada..3230252 100755
--- a/amp/src/ddl/comp_clk/source/clk_avsync.c
+++ b/amp/src/ddl/comp_clk/source/clk_avsync.c
@@ -61,6 +61,7 @@
 #define NUM_BD_QUEUE_OUTPUT_SIZE    4
 
 #define SAMPLE_INFO_SIZE            16
+#define AVS_CHECKER_LOG_BUFFER_SIZE 256
 
 #define AVSE(...)        AMPLOG(MODULE_AVS, AMP_LOG_ERROR, __VA_ARGS__)
 #define AVSH(...)        AMPLOG(MODULE_AVS, AMP_LOG_HIGH,  __VA_ARGS__)
@@ -121,6 +122,167 @@
     {    24,     1,   15000},
 };
 
+static void avsync_mgr_log(AVSYNC_MGR *pSyncMgr, SYNC_STREAM *pStream,
+                           AMP_BD_HANDLE hBD, BD_INFO *pBDInfo,
+                           AMP_CLK_AREN_INFO *pAudInfo, AMP_CLK_ACT eAct,
+                           UINT32 uiTime, UINT64 uiSTC, UINT32 uiPolicyDelay)
+{
+    UINT32 num = 0;
+    AMP_LOG_LEVEL eLevel = AMP_LOG_INFO;
+    char log_buffer[AVS_CHECKER_LOG_BUFFER_SIZE] = {0};
+    UINT32 writeIndex = 0;
+    UINT64 uiPTS = 0;
+    INT64 iPTSDiff = 0;
+    INT64 iSTCDiff = 0;
+    INT64 iPTSSTCDiff = 0;
+    UINT64 uiAOutPTS = 0;
+    INT64 iAOutPTSDiff = 0;
+    UINT32 uiBufferedBD = 0;
+    AMP_BD_HANDLE hBufDesc = NULL;
+    BOOL fEos = FALSE;
+
+    CLK_ASSERT(eAct < AMP_CLK_ACT_MAX);
+    CLK_ASSERT(pStream->m_eType < STREAM_TYPE_MAX);
+    CLK_ASSERT(pSyncMgr->m_eSyncStatus < SYNC_STATUS_MAX);
+    CLK_ASSERT(hBD != NULL || pBDInfo != NULL);
+
+    if (pStream->m_eType == STREAM_TYPE_VIDEO) {
+        eLevel = AMP_LOG_USER1;
+    } else if (pStream->m_eType == STREAM_TYPE_AUDIO) {
+        eLevel = AMP_LOG_USER2;
+    }
+
+    if ((eAct == AMP_CLK_DROP) && (pSyncMgr->m_eSyncStatus != SYNC_INIT)) {
+        eLevel = AMP_LOG_ERROR;
+    }
+
+    uiBufferedBD = bd_queue_get_fullness(pStream->m_pBdQueue);
+
+    // get PTS, BD, and EOS flag from BDInfo or BD
+    if (pBDInfo) {
+        uiPTS = GET_PTS_VAL64(pBDInfo->m_uiPtsStart);
+        hBufDesc = pBDInfo->m_hBD;
+        fEos = pBDInfo->m_fEosReached;
+    } else {
+        HRESULT ret;
+        UINT32 uiNumTag, uiTagIdx;
+        AMP_BDTAG_H *pTag = NULL;
+        AMP_BDTAG_AVS_PTS *pPTSTag = NULL;
+        AMP_BDTAG_AUD_FRAME_INFO *pInfoA = NULL;
+        AMP_BGTAG_FRAME_INFO *pInfoV = NULL;
+
+        hBufDesc = hBD;
+
+        ret = AMPBuf_BDTag_GetNum(hBufDesc, &uiNumTag);
+        if (ret == SUCCESS) {
+            for (uiTagIdx = 0; uiTagIdx < uiNumTag; uiTagIdx++) {
+                ret = AMPBuf_BDTag_GetWithIndex(hBufDesc, uiTagIdx, (VOID **)&pTag);
+                if (ret == SUCCESS) {
+                    switch (pTag->eType) {
+                        case AMP_BDTAG_SYNC_PTS_META:
+                            pPTSTag = (AMP_BDTAG_AVS_PTS *)pTag;
+                            uiPTS = GET_PTS_VAL64(
+                                       GET_FULL_PTS64(pPTSTag->uPtsHigh,
+                                                      pPTSTag->uPtsLow));
+                            break;
+                        case AMP_BDTAG_AUD_FRAME_CTRL:
+                            pInfoA = (AMP_BDTAG_AUD_FRAME_INFO *)pTag;
+                            if (pInfoA->uFlag & AMP_MEMINFO_FLAG_EOS_MASK) {
+                                fEos = TRUE;
+                            }
+                            break;
+                        case AMP_BGTAG_FRAME_INFO_META:
+                            pInfoV = (AMP_BGTAG_FRAME_INFO *)pTag;
+                            uiPTS = GET_PTS_VAL64(
+                                       GET_FULL_PTS64(pInfoV->uiPtsHigh,
+                                                      pInfoV->uiPtsLow));
+                            break;
+                        case AMP_BDTAG_ASSOCIATE_MEM_INFO:
+                            if (((AMP_BDTAG_MEMINFO *)pTag)->uFlag &
+                                AMP_MEMINFO_FLAG_EOS_MASK) {
+                                fEos = TRUE;
+                            }
+                            break;
+                         default:
+                            break;
+                    }
+                }
+            }
+        }
+    }
+
+    uiSTC = GET_PTS_VAL64(uiSTC);
+
+    iPTSDiff  = uiPTS - pStream->m_uiLastCheckPts;
+    iSTCDiff  = uiSTC - pStream->m_uiLastCheckStc;
+    iPTSSTCDiff = uiPTS - uiSTC;
+
+    // common AVS check log
+    num = snprintf(log_buffer, sizeof(log_buffer),
+            "[%d]CHECK_%s[%c][%c],"
+            "PTS:[0x%09llX][%lld],STC:[0x%09llX][%lld],PTS-STC:%lld,"
+            "BD:%p,BDID:%d,bufferedBDs:%2u,"
+            "CheckTimeDiff:%d,Delay:%5d/%d,Eos:%u,F:%u,RS:%u,",
+            pSyncMgr->m_pAVClock->m_uiClockID, pStream->m_szName,
+            pszActChar[eAct], pszSyncChar[pSyncMgr->m_eSyncStatus],
+            uiPTS, iPTSDiff, uiSTC, iSTCDiff, iPTSSTCDiff,
+            hBufDesc, hBufDesc->uiBDId, uiBufferedBD,
+            uiTime - pStream->m_uiLastCheckTime,
+            uiPolicyDelay, pStream->m_iUsrDelay, fEos, pStream->m_uiFCnt,
+            pStream->m_fResyncPending);
+
+    if (num >= sizeof(log_buffer)) {
+        AVSE("lack of log buffer, write: %d, remain:%d/%d \n", num,
+                sizeof(log_buffer), sizeof(log_buffer));
+        goto exit;
+    } else {
+        writeIndex += num;
+    }
+
+    // Audio related log
+    if (pAudInfo && IS_PTS_VALID64(pAudInfo->m_uiAOutPts)) {
+        uiAOutPTS    = GET_PTS_VAL64(pAudInfo->m_uiAOutPts);
+        iAOutPTSDiff = uiAOutPTS - pStream->m_uiLastCheckOutPts;
+
+        num = snprintf(log_buffer + writeIndex, sizeof(log_buffer) - writeIndex,
+            "AoutPTS:0x%08llX:%lld(%2u/%2u/%4u/%4u/%4u/%4u/%4u/%4u/%4u)",
+            uiAOutPTS, iAOutPTSDiff,
+            pAudInfo && pAudInfo->m_uiNumComps > 0 ?
+            pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 0 ?
+            pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 1 ?
+            pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 2 ?
+            pAudInfo->m_eAudCompInfo[2].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 3 ?
+            pAudInfo->m_eAudCompInfo[3].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 4 ?
+            pAudInfo->m_eAudCompInfo[4].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 5 ?
+            pAudInfo->m_eAudCompInfo[5].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 6 ?
+            pAudInfo->m_eAudCompInfo[6].m_uiInputFullness : 0,
+            pAudInfo && pAudInfo->m_uiNumComps > 7 ?
+            pAudInfo->m_eAudCompInfo[7].m_uiInputFullness : 0);
+
+        if (num >= sizeof(log_buffer) - writeIndex) {
+            AVSE("lack of log buffer, write: %d, remain:%d/%d \n", num,
+                    sizeof(log_buffer) - writeIndex, sizeof(log_buffer));
+            goto exit;
+        } else {
+            writeIndex += num;
+        }
+    }
+
+    AMPLOG(MODULE_AVS, eLevel, "%s", log_buffer);
+
+exit:
+    pStream->m_uiLastCheckStc       = uiSTC;
+    pStream->m_uiLastCheckPts       = uiPTS;
+    pStream->m_uiLastCheckOutPts    = uiAOutPTS;
+    pStream->m_uiLastCheckTime      = uiTime;
+}
 
 BD_INFO *stream_resync_to_bd(SYNC_STREAM *pStream, AMP_BD_HANDLE hBD)
 {
@@ -1073,141 +1235,6 @@
     return (uiAPPFullness > uiFullnessThresh ? AMP_CLK_HOLD : AMP_CLK_DISP);
 }
 
-VOID file_playback_debug(UINT64 uiSTCNow, INT32 iDelay, AMP_CLK_ACT eAct,
-                         AMP_BD_HANDLE hBD, BD_INFO *pBDInfo,
-                         SYNC_STREAM *pStream, AVSYNC_MGR *pSyncMgr,
-                         AMP_CLK_AREN_INFO *pAudInfo)
-{
-    UINT64 uiPTSNow = 0, uiOutPTSNow = 0;
-    UINT64 uiPTSDelta, uiSTCDelta, uiOutPTSDelta;
-    UINT32 uiBufferedBD;
-    AMP_BD_HANDLE hBufDesc = NULL;
-    AMP_LOG_LEVEL eLevel = AMP_LOG_INFO;
-    BOOL fEos = FALSE;
-
-    CLK_ASSERT(eAct < AMP_CLK_ACT_MAX);
-    CLK_ASSERT(pStream->m_eType < STREAM_TYPE_MAX);
-    CLK_ASSERT(pSyncMgr->m_eSyncStatus < SYNC_STATUS_MAX);
-
-    if (pStream->m_eType == STREAM_TYPE_VIDEO) {
-        eLevel = AMP_LOG_USER1;
-    } else if (pStream->m_eType == STREAM_TYPE_AUDIO) {
-        eLevel = AMP_LOG_USER2;
-    }
-
-    if ((eAct == AMP_CLK_DROP) && (pSyncMgr->m_eSyncStatus != SYNC_INIT)) {
-        eLevel = AMP_LOG_ERROR;
-    }
-
-    uiBufferedBD = bd_queue_get_fullness(pStream->m_pBdQueue);
-
-    if (pBDInfo) {
-        uiPTSNow = GET_PTS_VAL64(pBDInfo->m_uiPtsStart);
-        hBufDesc = pBDInfo->m_hBD;
-        fEos = pBDInfo->m_fEosReached;
-    } else {
-        HRESULT ret;
-        UINT32 uiNumTag, uiTagIdx;
-        AMP_BDTAG_H *pTag = NULL;
-        AMP_BDTAG_AVS_PTS *pPTSTag = NULL;
-        AMP_BDTAG_AUD_FRAME_INFO *pInfoA = NULL;
-        AMP_BGTAG_FRAME_INFO *pInfoV = NULL;
-
-        hBufDesc = hBD;
-
-        ret = AMPBuf_BDTag_GetNum(hBufDesc, &uiNumTag);
-        if (ret == SUCCESS) {
-            for (uiTagIdx = 0; uiTagIdx < uiNumTag; uiTagIdx++) {
-                ret = AMPBuf_BDTag_GetWithIndex(hBufDesc, uiTagIdx, (VOID **)&pTag);
-                if (ret == SUCCESS) {
-                    switch (pTag->eType) {
-                        case AMP_BDTAG_SYNC_PTS_META:
-                            pPTSTag = (AMP_BDTAG_AVS_PTS *)pTag;
-                            uiPTSNow = GET_PTS_VAL64(
-                                       GET_FULL_PTS64(pPTSTag->uPtsHigh,
-                                                      pPTSTag->uPtsLow));
-                            break;
-                        case AMP_BDTAG_AUD_FRAME_CTRL:
-                            pInfoA = (AMP_BDTAG_AUD_FRAME_INFO *)pTag;
-                            if (pInfoA->uFlag & AMP_MEMINFO_FLAG_EOS_MASK) {
-                                fEos = TRUE;
-                            }
-                            break;
-                        case AMP_BGTAG_FRAME_INFO_META:
-                            pInfoV = (AMP_BGTAG_FRAME_INFO *)pTag;
-                            uiPTSNow = GET_PTS_VAL64(
-                                       GET_FULL_PTS64(pInfoV->uiPtsHigh,
-                                                      pInfoV->uiPtsLow));
-                            break;
-                        case AMP_BDTAG_ASSOCIATE_MEM_INFO:
-                            if (((AMP_BDTAG_MEMINFO *)pTag)->uFlag &
-                                AMP_MEMINFO_FLAG_EOS_MASK) {
-                                fEos = TRUE;
-                            }
-                            break;
-                         default:
-                            break;
-                    }
-                }
-            }
-        }
-    }
-
-    if (pAudInfo && IS_PTS_VALID64(pAudInfo->m_uiAOutPts)) {
-        uiOutPTSNow = GET_PTS_VAL64(pAudInfo->m_uiAOutPts);
-    }
-
-    uiPTSDelta = uiPTSNow - pStream->m_uiLastCheckPts;
-    uiSTCDelta = uiSTCNow - pStream->m_uiLastCheckStc;
-    uiOutPTSDelta = uiOutPTSNow - pStream->m_uiLastCheckOutPts;
-
-    AMPLOG(MODULE_AVS, eLevel,
-           "[%d]CHECK_%s[%c][%c] PTS:%9llX(%5d)[%6d] "
-                        "STC:%9llX(%5d)[%6d] "
-                        "OUT:%9llX(%5d)[%6d] "
-                        "BD:%p(%x) "
-                        "R:%2u(%2u/%2u/%4u/%4u/%4u/%4u/%4u/%4u/%4u) "
-                        "D:%5d/%d E:%u F:%u, RS:%u",
-      pSyncMgr->m_pAVClock->m_uiClockID, pStream->m_szName,
-      pszActChar[eAct], pszSyncChar[pSyncMgr->m_eSyncStatus],
-      uiPTSNow, (INT32)uiPTSDelta,
-      pSyncMgr->m_pNewV && pSyncMgr->m_pNewA ?
-      (INT32)(GET_PTS_VAL64(pSyncMgr->m_pNewV->m_uiPTS) -
-              GET_PTS_VAL64(pSyncMgr->m_pNewA->m_uiPTS)) : 0,
-      uiSTCNow, (INT32)uiSTCDelta,
-      (INT32)(uiPTSNow - uiSTCNow),
-      uiOutPTSNow, (INT32)uiOutPTSDelta,
-      (INT32)(uiSTCNow - uiOutPTSNow),
-      hBufDesc, hBufDesc->uiBDId,
-      uiBufferedBD,
-      pAudInfo && pAudInfo->m_uiNumComps > 0 ?
-      pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 0 ?
-      pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 1 ?
-      pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 2 ?
-      pAudInfo->m_eAudCompInfo[2].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 3 ?
-      pAudInfo->m_eAudCompInfo[3].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 4 ?
-      pAudInfo->m_eAudCompInfo[4].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 5 ?
-      pAudInfo->m_eAudCompInfo[5].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 6 ?
-      pAudInfo->m_eAudCompInfo[6].m_uiInputFullness : 0,
-      pAudInfo && pAudInfo->m_uiNumComps > 7 ?
-      pAudInfo->m_eAudCompInfo[7].m_uiInputFullness : 0,
-      iDelay, pStream->m_iUsrDelay, fEos, pStream->m_uiFCnt,
-      pStream->m_fResyncPending);
-
-    pStream->m_uiLastCheckStc = uiSTCNow;
-    pStream->m_uiLastCheckPts = uiPTSNow;
-    pStream->m_uiLastCheckOutPts = uiOutPTSNow;
-
-    return;
-}
-
 VOID file_playback_check_bd_queue(SYNC_STREAM *pStream, UINT64 *pNextPTS,
                                 UINT32 *pBDNr, BOOL *pDisc)
 {
@@ -1545,6 +1572,7 @@
     UINT64 uiSTCNow, uiSTCAdj, uiPTSNow;
     UINT32 uiRateDen, uiBufferedBD, uiThresholdL, uiThresholdR;
     INT32 iRateNum, iDelay = 0;
+    UINT32 uiTime = 0;
     BD_INFO *pBDInfo = NULL;
     AMP_CLK_ACT eAct = AMP_CLK_HOLD;
 
@@ -1553,6 +1581,7 @@
     CLK_ASSERT(pSyncMgr->m_pStreams[pStream->m_uiIndex] == pStream);
     CLK_ASSERT(pStream->m_pBdQueue);
 
+    uiTime   = AMP_GetCurrentTimeMS();
     uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, TRUE));
 
     avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen);
@@ -1716,9 +1745,8 @@
     }
 
 Exit:
-    file_playback_debug(uiSTCNow, iDelay, eAct,
-                        hBD, pBDInfo,
-                        pStream, pSyncMgr, NULL);
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime,
+            uiSTCNow, iDelay);
 
     if (eAct != AMP_CLK_HOLD) {
         if (pBDInfo) {
@@ -1761,6 +1789,7 @@
     UINT64 uiSTCNow, uiSTCAdj, uiPTSNow;
     UINT32 uiRateDen, uiBufferedBD, uiThresholdL, uiThresholdR;
     INT32 iRateNum = 0;
+    UINT32 uiTime = 0;
     BD_INFO *pBDInfo = NULL;
     AMP_CLK_AREN_INFO *pAudInfo = NULL;
     AMP_CLK_ACT eAct = AMP_CLK_HOLD;
@@ -1772,6 +1801,7 @@
 
     pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData;
 
+    uiTime   = AMP_GetCurrentTimeMS();
     uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, FALSE));
 
     avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen);
@@ -1942,9 +1972,8 @@
     }
 
 Exit:
-    file_playback_debug(uiSTCNow, pStream->m_iDelay, eAct,
-                        hBD, pBDInfo,
-                        pStream, pSyncMgr, pAudInfo);
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime,
+            uiSTCNow, pStream->m_iDelay);
 
     if (eAct != AMP_CLK_HOLD) {
         if (pBDInfo) {
@@ -2114,6 +2143,7 @@
     UINT64 uiSTCNow, uiSTCAdj, uiPTSNow;
     UINT32 uiBufferedSamples, uiRateDen, uiThresholdL, uiThresholdR;
     INT32 iRateNum = 0, iDelay = 0;
+    UINT32 uiTime = 0;
     BD_INFO *pBDInfo = NULL;
     AMP_CLK_ACT eAct = AMP_CLK_HOLD;
     BOOL fPullDown;
@@ -2123,6 +2153,7 @@
     CLK_ASSERT(pSyncMgr->m_pStreams[pStream->m_uiIndex] == pStream);
     CLK_ASSERT(pStream->m_pBdQueue);
 
+    uiTime   = AMP_GetCurrentTimeMS();
     uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, TRUE));
     avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen);
 
@@ -2190,9 +2221,8 @@
     }
 
 Exit:
-    file_playback_debug(uiSTCNow, iDelay, eAct,
-                        hBD, pBDInfo,
-                        pStream, pSyncMgr, NULL);
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime,
+            uiSTCNow, iDelay);
 
     if (eAct != AMP_CLK_HOLD) {
         if (pBDInfo) {
@@ -2220,6 +2250,7 @@
     UINT64 uiSTCNow, uiSTCAdj, uiPTSNow;
     UINT32 uiRateDen, uiBufferedSamples, uiThresholdL, uiThresholdR;
     INT32 iRateNum = 0;
+    UINT32 uiTime = 0;
     BD_INFO *pBDInfo = NULL;
     AMP_CLK_AREN_INFO *pAudInfo = NULL;
     AMP_CLK_ACT eAct = AMP_CLK_HOLD;
@@ -2230,6 +2261,7 @@
     CLK_ASSERT(pRndInfo);
 
     pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData;
+    uiTime   = AMP_GetCurrentTimeMS();
     uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, FALSE));
     avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen);
 
@@ -2319,9 +2351,8 @@
     }
 
 Exit:
-    file_playback_debug(uiSTCNow, pStream->m_iDelay, eAct,
-                        hBD, pBDInfo,
-                        pStream, pSyncMgr, pAudInfo);
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime,
+            uiSTCNow, pStream->m_iDelay);
 
     if (eAct != AMP_CLK_HOLD) {
         if (pBDInfo) {
@@ -2779,24 +2810,8 @@
     }
 
 _Exit:
-
-    AVSU1("[AVS][%d]CHECK_%s([%c][%c%c%c%c] V:0x%08x(%d), M:0x%08x(%d)[%d], "
-          "AM:0x%08x, AM-V:%d)\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eActP], pszActChar[eActN], pszActChar[eActL],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0,
-          (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc),
-          uiTime - pStream->m_uiLastCheckTime,
-          (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0);
-
-    //eAct = AMP_CLK_DISP;
-
-    pStream->m_uiLastCheckStc = uiOrigSTC;
-    pStream->m_uiLastCheckTime = uiTime;
-    if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime,
+            uiOrigSTC, uiDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
@@ -2950,26 +2965,8 @@
         }
     }
 
-
-    AVSU2("[AVS][%d]CHECK_%s([%d][%c][%c%c%c%c] PTS:0x%08x, STC:0x%08x(%d),"
-          " D:%d, O:0x%08x(%d), AM:0x%08x(%d))\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          uiTime - pStream->m_uiLastCheckTime,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eActP], pszActChar[eActN], pszActChar[eActL],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc),
-          pStream->m_iDelay, (UINT32)pStream->m_uiOutPTS,
-          pBDInfo ? (INT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) -
-                     GET_PTS_VAL64(pStream->m_uiOutPTS)) / 90 : 0,
-          uiSTC + pStream->m_iDelay,
-          pBDInfo ? (INT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) -
-                     GET_PTS_VAL64(uiSTC + pStream->m_iDelay)) / 90 : 0);
-
-    //eAct = AMP_CLK_DISP;
-    pStream->m_uiLastCheckStc = uiSTC;
-    pStream->m_uiLastCheckTime = uiTime;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime,
+            uiSTC, pStream->m_iDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
@@ -3799,24 +3796,8 @@
     }
 
 _Exit:
-    //eAct = AMP_CLK_DISP;
-    AVSU1("[AVS][%d]CHECK_%s([%c][%c%c%c%c] V:0x%08x(%d), M:0x%08x(%d)[%d], "
-          "AM:0x%08x, AM-V:%d)%s, usrdelay %d ms, range %d\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eActP], pszActChar[eActN], pszActChar[eActL],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0,
-          (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc),
-          uiTime - pStream->m_uiLastCheckTime,
-          (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0,
-          (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "",
-          pStream->m_iUsrDelay/90, uiRange);
-
-    pStream->m_uiLastCheckStc = uiOrigSTC;
-    pStream->m_uiLastCheckTime = uiTime;
-    if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime,
+            uiOrigSTC, uiDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
@@ -4012,30 +3993,8 @@
         }
     }
 
-    //eAct = AMP_CLK_DISP;
-    AVSU2("[AVS][%d]CHECK_%s([%c][%c%c%c%c] A:0x%08x(%d), M:0x%08x(%d)[%d], "
-          "O:0x%08x, A:[%d, %d][%d]%s)\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eActP], pszActChar[eActN], pszActChar[eActL],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          pBDInfo ? (UINT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) -
-                    GET_PTS_VAL64(pStream->m_uiLastCheckPts)) : 0,
-          (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc),
-          uiTime - pStream->m_uiLastCheckTime,
-          pAudInfo ? (UINT32)pAudInfo->m_uiAOutPts : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 0) ?
-              pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 0) ?
-              pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 1) ?
-              pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0,
-          (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "");
-
-    pStream->m_uiLastCheckStc = uiSTC;
-    pStream->m_uiLastCheckTime = uiTime;
-    pStream->m_uiLastCheckPts = pBDInfo ? pBDInfo->m_uiPtsStart : 0;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime,
+            uiSTC, pStream->m_iDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
@@ -4439,23 +4398,8 @@
     eAct = check_pts_range(pBDInfo->m_uiPtsStart, uiSTC, uiRangeL, uiRangeR,
                             pSyncMgr->m_fBackward);
 _Exit:
-    //eAct = AMP_CLK_DISP;
-    AVSU1("[AVS][%d]CHECK_%s([%c][%c] V:0x%08x(%d), M:0x%08x(%d)[%d], "
-          "AM:0x%08x, AM-V:%d)%s, usrdelay %d ms\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0,
-          (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc),
-          uiTime - pStream->m_uiLastCheckTime,
-          (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0,
-          (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "",
-          pStream->m_iUsrDelay/90);
-
-    pStream->m_uiLastCheckStc = uiOrigSTC;
-    pStream->m_uiLastCheckTime = uiTime;
-    if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime,
+            uiOrigSTC, uiDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
@@ -4485,7 +4429,7 @@
                      AMP_CLK_ACT *pAction, AMP_CLK_DROP_INFO *pDropInfo)
 {
     BD_INFO *pBDInfo = 0;
-    AMP_CLK_ACT eActP, eActN, eActL, eAct;
+    AMP_CLK_ACT eAct;
     UINT64 uiSTC = 0;
     UINT32 uiTime = 0, uiRateDen;
     INT32 iRateNum;
@@ -4500,7 +4444,6 @@
 
     pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData;
     eAct = AMP_CLK_DISP;
-    eActP = eActN = eActL = AMP_CLK_ACT_MAX;
     pBDInfo = stream_resync_to_bd(pStream, hBD);
 
     if (pSyncMgr->m_eSyncStatus == SYNC_DISABLED) {
@@ -4539,31 +4482,8 @@
     }
 
 _Exit:
-
-    //eAct = AMP_CLK_DISP;
-    AVSU2("[AVS][%d]CHECK_%s([%c][%c%c%c%c] A:0x%08x(%d), M:0x%08x(%d)[%d], "
-          "O:0x%08x, A:[%d, %d][%d]%s)\n",
-          pSyncMgr->m_pAVClock->m_uiClockID,
-          pStream->m_szName,
-          pszSyncChar[pSyncMgr->m_eSyncStatus],
-          pszActChar[eActP], pszActChar[eActN], pszActChar[eActL],
-          pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0,
-          pBDInfo ? (UINT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) -
-                    GET_PTS_VAL64(pStream->m_uiLastCheckPts)) : 0,
-          (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc),
-          uiTime - pStream->m_uiLastCheckTime,
-          pAudInfo ? (UINT32)pAudInfo->m_uiAOutPts : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 0) ?
-              pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 0) ?
-              pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0,
-          pAudInfo && (pAudInfo->m_uiNumComps > 1) ?
-              pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0,
-          (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "");
-
-    pStream->m_uiLastCheckStc = uiSTC;
-    pStream->m_uiLastCheckTime = uiTime;
-    pStream->m_uiLastCheckPts = pBDInfo ? pBDInfo->m_uiPtsStart : 0;
+    avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime,
+            uiSTC, pStream->m_iDelay);
 
     if ((AMP_CLK_HOLD != eAct) && pBDInfo) {
         pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;
CSMSAAI-109-91998-458f0fb.diff (26,205 bytes)   

(ALTech) Sangmin Choi

2023-01-10 14:18

developer   ~0011733

Hello, Jacky,

Could you please assign an engineer for this issue?

And, Synaptics engineer told me that this patch would not be generated under same code base.
So, maybe you can get any conflicts during merge.
Please modify the conflict and if you have questions, please contact to Synaptics.

And, this patch should be applied to 534 branch.

Thank you.

(SW) Jacky Chiang

2023-01-10 16:21

manager   ~0011735

Hi Sangmin,

  OK, I will have Jim to apply this patch and modify the conflict accordingly.

Thanks,
Jacky

(SW) Jim Chen

2023-01-10 20:10

developer   ~0011736

Hi Sangmin,
It is pushed to 534 and build was ok.
But I didn't check the functionality.
Please help verify with the daily build tonight.

(ALTech) Sangmin Choi

2023-01-11 10:00

developer   ~0011737

Hi, Jim,

I checked the log message was printed correctly.

FYI, to see the log messages you should enable the amp log level.
# ampdiag setmodl AVS 7

Thank you.
Sangmin Choi.

Issue History

Date Modified Username Field Change
2023-01-10 14:14 (ALTech) Sangmin Choi New Issue
2023-01-10 14:14 (ALTech) Sangmin Choi Status new => assigned
2023-01-10 14:14 (ALTech) Sangmin Choi Assigned To => (SW) Jacky Chiang
2023-01-10 14:14 (ALTech) Sangmin Choi File Added: CSMSAAI-109-91998-458f0fb.diff
2023-01-10 14:18 (ALTech) Sangmin Choi Note Added: 0011733
2023-01-10 16:21 (SW) Jacky Chiang Note Added: 0011735
2023-01-10 16:21 (SW) Jacky Chiang Assigned To (SW) Jacky Chiang => (SW) Jim Chen
2023-01-10 20:10 (SW) Jim Chen Note Added: 0011736
2023-01-11 10:00 (ALTech) Sangmin Choi Note Added: 0011737
2023-01-11 10:00 (ALTech) Sangmin Choi Status assigned => closed
2023-01-11 10:00 (ALTech) Sangmin Choi Resolution open => fixed